Query execution differences - Mailing list pgsql-sql

Hello,

I am running into some runtime differences that do not seem to make
sense and would like some help interpreting the EXPLAIN ANALYZE
output.

I have run 2 identical queries, one for each company. Company 1
returns 628 records in a time of 674ms and Company 2 returns 73
records in a time of 4051ms.

Because of the table structure it is possible that Company 2 could
have more rows in specific queries but not at anywhere near the
records currently in the system.

I am including/attaching the explain analyze output for both
companies, it's kind of wide so I hope the email servers don't munge
the pasted version. Some info on what each section does would help or
if someone knows of a reference I could check out would work too. I
checked the Docs on explain but did not see anything that helped me
out.

Thanks.

Ray A.



Sort  (cost=2323.82..2323.91 rows=35 width=78) (actual
time=650.345..650.775 rows=628 loops=1)
   Sort Key: oa.date_created
   ->  Hash Left Join  (cost=2304.35..2322.92 rows=35 width=78)
(actual time=609.815..646.398 rows=628 loops=1)
         Hash Cond: ("outer".order_number = "inner".order_number)
         ->  Merge Left Join  (cost=2141.36..2159.22 rows=35 width=66)
(actual time=568.392..595.386 rows=628 loops=1)
               Merge Cond: ("outer".order_number = "inner".order_number)
               ->  Merge Left Join  (cost=1920.33..1927.06 rows=35
width=58) (actual time=489.753..504.345 rows=628 loops=1)
                     Merge Cond: ("outer".order_number = "inner".order_number)
                     ->  Sort  (cost=1490.02..1490.11 rows=35
width=50) (actual time=339.998..340.466 rows=628 loops=1)
                           Sort Key: oa.order_number
                           ->  Nested Loop  (cost=1320.09..1489.13
rows=35 width=50) (actual time=271.391..332.113 rows=628 loops=1)
                                 ->  Merge Join
(cost=1320.09..1335.74 rows=39 width=44) (actual
time=270.675..300.962 rows=628 loops=1)
                                       Merge Cond:
("outer"."?column4?" = "inner"."?column8?")
                                       ->  Sort  (cost=873.62..880.80
rows=2874 width=18) (actual time=178.135..180.123 rows=2714 loops=1)
                                             Sort Key: (ci.storeno)::text
                                             ->  Seq Scan on
customer_information ci  (cost=0.00..708.52 rows=2874 width=18)
(actual time=0.264..119.093 rows=2781 loops=1)
                                                   Filter:
('deere'::text = (company_name)::text)
                                       ->  Sort  (cost=446.47..446.91
rows=177 width=51) (actual time=92.411..92.970 rows=628 loops=1)
                                             Sort Key: (oa.storeno)::text
                                             ->  Seq Scan on
order_admin oa  (cost=0.00..439.86 rows=177 width=51) (actual
time=2.634..77.551 rows=628 loops=1)
                                                   Filter:
(((order_status)::text = 'completed'::text) AND ((company_name)::text
= 'deere'::text) AND ((group_code)::text = '2005'::text))
                                 ->  Index Scan using
order_address_pkey on order_address oad  (cost=0.00..3.92 rows=1
width=10) (actual time=0.029..0.033 rows=1 loops=628)
                                       Index Cond:
("outer".order_number = oad.order_number)
                     ->  Sort  (cost=430.30..433.56 rows=1302
width=12) (actual time=144.569..146.378 rows=2436 loops=1)
                           Sort Key: impn.order_number
                           ->  Subquery Scan impn
(cost=346.67..362.95 rows=1302 width=12) (actual
time=109.041..129.276 rows=2436 loops=1)
                                 ->  HashAggregate
(cost=346.67..349.93 rows=1302 width=8) (actual time=109.025..119.439
rows=2436 loops=1)
                                       ->  Hash Join
(cost=17.98..340.16 rows=1302 width=8) (actual time=24.299..92.981
rows=2644 loops=1)
                                             Hash Cond:
("outer".item_id = "inner".item_id)
                                             ->  Seq Scan on
order_items oi  (cost=0.00..279.15 rows=6002 width=8) (actual
time=0.203..64.595 rows=5902 loops=1)
                                                   Filter: (has_imprint = true)
                                             ->  Hash
(cost=17.89..17.89 rows=36 width=12) (actual time=2.991..2.991 rows=0
loops=1)
                                                   ->  Hash Join
(cost=14.07..17.89 rows=36 width=12) (actual time=2.522..2.862
rows=36 loops=1)
                                                         Hash Cond:
("outer".item_id = "inner".item_id)
                                                         ->  Seq Scan
on items_imprint ii  (cost=0.00..1.36 rows=36 width=8) (actual
time=0.084..0.178 rows=36 loops=1)
                                                         ->  Hash
(cost=13.66..13.66 rows=166 width=4) (actual time=2.319..2.319 rows=0
loops=1)
                                                               ->  Seq
Scan on items i  (cost=0.00..13.66 rows=166 width=4) (actual
time=0.150..1.814 rows=166 loops=1)
               ->  Sort  (cost=221.04..226.52 rows=2192 width=12)
(actual time=73.412..75.043 rows=2273 loops=1)
                     Sort Key: impv.order_number
                     ->  Subquery Scan impv  (cost=72.00..99.40
rows=2192 width=12) (actual time=28.835..47.994 rows=2273 loops=1)
                           ->  HashAggregate  (cost=72.00..77.48
rows=2192 width=8) (actual time=28.822..38.805 rows=2273 loops=1)
                                 ->  Seq Scan on imprint_bridge ib
(cost=0.00..60.29 rows=2343 width=8) (actual time=0.178..12.879
rows=2344 loops=1)
                                       Filter: (imprint_verified = true)
         ->  Hash  (cost=162.85..162.85 rows=55 width=16) (actual
time=41.242..41.242 rows=0 loops=1)
               ->  Subquery Scan un  (cost=162.03..162.85 rows=55
width=16) (actual time=40.045..40.882 rows=91 loops=1)
                     ->  HashAggregate  (cost=162.03..162.30 rows=55
width=12) (actual time=40.027..40.490 rows=91 loops=1)
                           ->  Seq Scan on customer_relations cr
(cost=0.00..161.31 rows=95 width=12) (actual time=0.307..38.249
rows=111 loops=1)
                                 Filter: ((order_number IS NOT NULL)
AND ((status)::text <> 'resolved'::text))
Total runtime: 674.458 ms




Sort  (cost=996.26..996.27 rows=1 width=78) (actual
time=4027.483..4027.535 rows=73 loops=1)
   Sort Key: oa.date_created
   ->  Nested Loop Left Join  (cost=580.70..996.25 rows=1 width=78)
(actual time=244.610..4025.749 rows=73 loops=1)
         Join Filter: ("outer".order_number = "inner".order_number)
         ->  Nested Loop Left Join  (cost=418.67..832.71 rows=1
width=66) (actual time=211.388..3911.800 rows=73 loops=1)
               Join Filter: ("outer".order_number = "inner".order_number)
               ->  Nested Loop Left Join  (cost=346.67..705.91 rows=1
width=58) (actual time=153.052..2093.386 rows=73 loops=1)
                     Join Filter: ("outer".order_number = "inner".order_number)
                     ->  Nested Loop  (cost=0.00..326.69 rows=1
width=50) (actual time=22.476..102.703 rows=73 loops=1)
                           ->  Nested Loop  (cost=0.00..322.76 rows=1
width=44) (actual time=21.600..91.037 rows=73 loops=1)
                                 ->  Index Scan using
idx_order_admin_company_name on order_admin oa  (cost=0.00..292.82
rows=5 width=51) (actual time=12.154..63.989 rows=73 loops=1)
                                       Index Cond:
((company_name)::text = 'harley'::text)
                                       Filter: (((order_status)::text
= 'completed'::text) AND ((group_code)::text = '2005'::text))
                                 ->  Index Scan using
customer_information_pkey on customer_information ci
(cost=0.00..5.97 rows=1 width=18) (actual time=0.314..0.320 rows=1
loops=73)
                                       Index Cond:
(((ci.storeno)::text = ("outer".storeno)::text) AND ('harley'::text =
(ci.company_name)::text))
                           ->  Index Scan using order_address_pkey on
order_address oad  (cost=0.00..3.92 rows=1 width=10) (actual
time=0.105..0.127 rows=1 loops=73)
                                 Index Cond: ("outer".order_number =
oad.order_number)
                     ->  Subquery Scan impn  (cost=346.67..362.95
rows=1302 width=12) (actual time=1.792..21.237 rows=2436 loops=73)
                           ->  HashAggregate  (cost=346.67..349.93
rows=1302 width=8) (actual time=1.788..12.441 rows=2436 loops=73)
                                 ->  Hash Join  (cost=17.98..340.16
rows=1302 width=8) (actual time=38.136..114.149 rows=2644 loops=1)
                                       Hash Cond: ("outer".item_id =
"inner".item_id)
                                       ->  Seq Scan on order_items oi
(cost=0.00..279.15 rows=6002 width=8) (actual time=0.236..75.019
rows=5902 loops=1)
                                             Filter: (has_imprint = true)
                                       ->  Hash  (cost=17.89..17.89
rows=36 width=12) (actual time=13.865..13.865 rows=0 loops=1)
                                             ->  Hash Join
(cost=14.07..17.89 rows=36 width=12) (actual time=13.384..13.741
rows=36 loops=1)
                                                   Hash Cond:
("outer".item_id = "inner".item_id)
                                                   ->  Seq Scan on
items_imprint ii  (cost=0.00..1.36 rows=36 width=8) (actual
time=9.804..9.902 rows=36 loops=1)
                                                   ->  Hash
(cost=13.66..13.66 rows=166 width=4) (actual time=3.442..3.442 rows=0
loops=1)
                                                         ->  Seq Scan
on items i  (cost=0.00..13.66 rows=166 width=4) (actual
time=0.173..2.922 rows=166 loops=1)
               ->  Subquery Scan impv  (cost=72.00..99.40 rows=2192
width=12) (actual time=0.498..19.018 rows=2273 loops=73)
                     ->  HashAggregate  (cost=72.00..77.48 rows=2192
width=8) (actual time=0.493..10.664 rows=2273 loops=73)
                           ->  Seq Scan on imprint_bridge ib
(cost=0.00..60.29 rows=2343 width=8) (actual time=6.099..20.142
rows=2344 loops=1)
                                 Filter: (imprint_verified = true)
         ->  Subquery Scan un  (cost=162.03..162.85 rows=55 width=16)
(actual time=0.457..1.292 rows=91 loops=73)
               ->  HashAggregate  (cost=162.03..162.30 rows=55
width=12) (actual time=0.451..0.926 rows=91 loops=73)
                     ->  Seq Scan on customer_relations cr
(cost=0.00..161.31 rows=95 width=12) (actual time=0.295..30.163
rows=111 loops=1)
                           Filter: ((order_number IS NOT NULL) AND
((status)::text <> 'resolved'::text))
Total runtime: 4051.941 ms

--